<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" 
  "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">

<html xmlns="http://www.w3.org/1999/xhtml">
  <head>
    <meta http-equiv="content-type" content="text/html; charset=iso-8859-1" />
    <title>Email per transaction</title>
    <link rel="stylesheet" type="text/css" href="../css/common.css" />
    <link rel="stylesheet" type="text/css" href="../css/screen.css" media="screen" />
    <link rel="stylesheet" type="text/css" href="../css/_print.css" media="print" />
    <link rel="stylesheet" type="text/css" href="../css/prettify.css" media="screen" />

  </head>
  <body onload="prettyPrint()">
    <script type="text/javascript">prefix='../';</script>
    <script type="text/javascript" src="../js/prettify.js"></script>
    <script src="../templates/header.js" type="text/javascript"></script>
    <div id="left">
      <noscript>Please turn on Javascript to view this menu</noscript>
      <script src="../templates/left.js" type="text/javascript"></script>
    </div>
    <div id="content">
      
      <h2>Triggering an email containing the isolated logs of selected
      transactions</h2>
      
      <p>Let Dave and Carol be software QA engineers working at a
      company called Fooware.com. As you might have guessed,
      Fooware.com sells foos. Yes, foos... Let <em>Buscrit</em> be a
      business critical backend system running at Fooware.com. Buscrit
      is called by a number of applications to make business-critical
      transactions of various types.
      </p>

      <p>We would like to allow Carol to access the logging data
      generated by Buscrit as conveniently as possible. We could
      assume that Carol has access the log files directly on the
      server where Buscrit runs. However, let us assume that accessing
      the log files is somehow impractical because one or ore more of
      the following conditions holds true:
      </p>

      <ol>
        <li>Buscrit runs on multiple hosts and it is difficult to
        identify the host where a particular transaction was
        executed</li>
        <li>Carol does not (or does not wish to) have access to the
        hosts where Buscrit runs
        </li>
        <li>Buscrit is tested by multiple testers, e.g. Dave and Carol
        and others, simultaneously so that it is hard to identify and
        track an individual transaction in the log files
        </li>
      </ol>

      <p>Given the above circumstances, let us create a logback
      configuration so that Carol receives an email message at the end
      of every transaction. We will iteratively refine this
      configuration so that Carol will receive an email containing the
      logs of each transaction in isolation and only for the
      transactions she explicitly selects.
      </p>

      <h3>Triggering an email message at the end of each transaction</h3>

      <p>We will be using <code>SMTPAppender</code> to generate emails
      containing logging data. Please refer to the <a
      href="../manual/appenders.html#SMTPAppender">appropriate section
      of the manual</a> to familiarize yourself with
      <code>SMTPAppender</code> and its properties.
      </p> 

      <p>The <a href="demo.html">logback-demo</a> project contains a
      Struts action called <a
      href="http://logback-demo.qos.ch/xref/ch/qos/logback/demo/prime/PrimeAction.html"><code>PrimeAction</code></a>. It
      can factorize integers. Here is the pertinent structure of
      <code>PrimeAction</code>'s code:</p>

      <pre class="prettyprint source">package ch.qos.logback.demo.prime;

import org.apache.struts.action.Action;
...
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

public class PrimeAction extends Action {

  Logger logger = LoggerFactory.getLogger(PrimeAction.class);
  static Marker SMTP_TRIGGER = MarkerFactory.getMarker("SMTP_TRIGGER");

  public ActionForward execute(ActionMapping actionMapping,
                               ActionForm actionForm, HttpServletRequest request,
                               HttpServletResponse response) throws Exception {

    PrimeForm form = (PrimeForm) actionForm;

    Long number = form.getNumber();
    try {
      NumberCruncher nc = new NumberCruncherImpl();
      Long start = System.currentTimeMillis();
      Long[] result = nc.factor(number);
      Long duration = System.currentTimeMillis() - start;
      logger.info("Results computed in {} ms", duration);

      ...
    } finally {
      <b>logger.info(SMTP_TRIGGER, "Prime computation ended");</b>
    }
  }
} </pre>

      <p>In a real world application, a transaction would involve
      systems external to the application, e.g. a database or a
      messaging queue. For the sake of this example, let us consider
      each factorization request as a <em>transaction</em>.  At the
      end of each factorization request, i.e. each transaction, the
      logger of the <code>PrimeAction</code> instance is invoked with
      the SMTP_TRIGGER marker and the message "Prime computation
      ended".  We can capitalize on this logging request to clearly
      identify the end of every transaction in order to trigger an
      outgoing email message.
     </p>

     <p>Here is a configuration file which uses
     <code>JaninoEventEvaluator</code> to trigger an outgoing email
     for logging event marked with SMTP_TRIGGER.
     </p> 

    <pre class="prettyprint
     source">&lt;configuration scan="true" scanPeriod="3 seconds">

  &lt;!-- always a good idea to have an OnConsoleStatusListener -->
  &lt;statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

  &lt;appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    &lt;smtpHost>NAME_OF_SMTP_HOST&lt;/smtpHost>
    &lt;to>...&lt;/to>                                         
    &lt;from>...&lt;/from>
    &lt;subject>Prime - %mdc{number} by %mdc{userid} &lt;/subject>
    &lt;layout class="ch.qos.logback.classic.html.HTMLLayout">
      &lt;pattern>%date%level%logger{24}%msg&lt;/pattern>
    &lt;/layout>
    
    <b>&lt;evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator"></b>
      <b>&lt;expression></b>
        <b>marker != null  &amp;&amp; marker.contains("SMTP_TRIGGER")</b>
      <b>&lt;/expression></b>
    <b>&lt;/evaluator></b>
  &lt;/appender>

  &lt;root level="DEBUG">
    &lt;appender-ref ref="SMTP" /> 
  &lt;/root>

&lt;/configuration></pre>

      

   <h3>Transaction isolation</h3>

   <p>While the previous configuration file will trigger an outgoing
   email message whenever an event is marked with "SMTP_TRIGGER", the
   contents of the message will contain events generated by different
   transactions. With a little effort, we can actually separate events
   belonging to different transactions so that the outgoing email
   triggered at the end of the transaction contains logs from that
   transaction and only that transaction.
   </p>

  <p>To isolate a given transaction, there must first be a way to
  distinguish it from other transactions. Typically this would be
  accomplished by putting the unique identifier of the transaction
  into the MDC.
  </p>

  <pre class="prettyprint source">String transactionId = ...; // extract id from transaction 
MDC.put("txId", transactionId); </pre>

  <p>In the <a
  href="http://logback-demo.qos.ch/xref/ch/qos/logback/demo/UserServletFilter.html"><code>UserServletFilter</code></a>
  class, this is done by retrieving the id of the session and putting
  it into the MDC under the key "txId".</p>


    <pre class="prettyprint source">public class UserServletFilter implements Filter {

   public void doFilter(ServletRequest request, ServletResponse response,
                       FilterChain chain) throws IOException, ServletException {

    HttpServletRequest req = (HttpServletRequest) request;
    HttpSession session = req.getSession();
    MDC.put("txId", session.getId());
    ...
    try {
      // invoke subsequent filters
      chain.doFilter(request, response);
    } finally {
      // always clear the MDC at the end of the request
      MDC.clear();
    }
  }
}</pre>


  <p>By setting an appropriate discriminator in SMTPAppender, you can
  can scatter incoming events into different buffers according to the
  value returned by the discriminator. Given that each request session
  is placed under the MDC key "txId", we can use an MDC-based
  discriminator to isolate the logs generated by each transaction.
  </p>

  <pre class="prettyprint source">&lt;configuration scan="true" scanPeriod="3 seconds">

  &lt;statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />

  &lt;appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    &lt;smtpHost>NAME_OF_SMTP_HOST&lt;/smtpHost>
    &lt;to>...&lt;/to>                                         
    &lt;from>...&lt;/from>

    &lt;smtpHost>NAME_OF_SMTP_HOST&lt;/smtpHost>
    &lt;to>name@some.smtp.host&lt;/to>
    &lt;from>testing@...&lt;/from>
    &lt;subject>Prime - %mdc{number} by %mdc{userid} &lt;/subject>
    &lt;layout class="ch.qos.logback.classic.html.HTMLLayout">
       &lt;pattern>%date%level%logger{24}%msg&lt;/pattern>
    &lt;/layout>

    &lt;evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator">
      &lt;expression>
        marker != null &amp;&amp; marker.contains("SMTP_TRIGGER") 
      &lt;/expression>
    &lt;/evaluator>

    <b>&lt;discriminator class="ch.qos.logback.classic.sift.MDCBasedDiscriminator"></b>
      <b>&lt;key>txId&lt;/key></b>
      <b>&lt;defaultValue>default&lt;/defaultValue></b>
    <b>&lt;/discriminator></b>
  &lt;/appender>  

  &lt;root level="DEBUG">
    &lt;appender-ref ref="SMTP" /> 
  &lt;/root>
&lt;/configuration> </pre>

   <p>After starting the logback-demo web-application with the above
   configuration file (with <span class="option">smtpHost</span> and
   <span class="option">to</span> options adapted for my environment)
   on localhost and then visiting the <a
   href="http://localhost:8070/logback-demo/prime.jsp">Prime
   number</a> page to factorize the number 123, I received the
   following email:
   </p>

   <img src="images/factorEmail0.png" alt="selective email0"/>
      
   <p>Note that the above email contains the logs generated by the
   factorization of the number 123, without log pollution from any
   other "transaction".
   </p>

  <h3>Selective triggering &amp; recipient addressing with transaction isolation</h3>

  <p>In a real world scenario, receiving isolated transactions is not
  enough. You would need to trigger outgoing emails only for certain
  users, typically QA engineers such as Dave and Carol. Moreover, you
  would want the emails generated by transaction made by Carol to
  Carol's mailbox and those generated by Dave to Dave's mailbox.</p>

  <p>Selective triggering and addressing are two distinct
  problems. Depending on the exact circumstances, there are many ways
  of tackling these two issues. However, for the sake of simplicity,
  let us assume that the SMTP server at Fooware.com accepts <a
  href="http://en.wikipedia.org/wiki/Email_address#Address_tags">address
  tags</a>. Such an SMTP server treats an incoming message sent to
  username+xyz@fooware.com as if it were addressed to
  username@fooware.com, effectively stripping the +xyz part.</p>

  <p>Let us further assume that we can somehow extract the email
  address of the user from the contents of her transaction, via a
  database lookup or perhaps some other means. The extracted email
  addressed is placed into the MDC under the key "txEmail".
  </p>

  <p>Upon a logging event marked as SMTP_TRIGGER, the following
  configuration file will trigger an email message addressed to the
  value of "%mdc{txEmail}" but only if it contains the string "+log".
  </p>

  <pre class="prettyprint source">&lt;configuration scan="true" scanPeriod="3 seconds">

  &lt;statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" /&gt;

  &lt;appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    &lt;SMTPHost>NAME_OF_SMTP_HOST&lt;/SMTPHost>
    <b>&lt;to>%mdc{txEmail}&lt;/to></b>
    &lt;from>&lt;/from>
    &lt;subject>Prime - %mdc{number}&lt;/subject>

    &lt;layout class="ch.qos.logback.classic.html.HTMLLayout">
       &lt;pattern>%date%level%logger{24}%msg&lt;/pattern>
    &lt;/layout>

    &lt;discriminator class="ch.qos.logback.classic.sift.MDCBasedDiscriminator">
      &lt;key>txId&lt;/key>
      &lt;defaultValue>default&lt;/defaultValue>
    &lt;/discriminator>

    &lt;evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator">
      &lt;expression>
        <b>(mdc != null &amp;amp;&amp;amp; mdc.get("txEmail") != null &amp;amp;&amp;amp; </b>
            <b>((String) mdc.get("txEmail")).contains("+log") )</b>
        &amp;amp;&amp;amp;
        (marker != null  &amp;&amp; marker.contains("SMTP_TRIGGER") )
      &lt;/expression>
    &lt;/evaluator>
  &lt;/appender>

  &lt;root level="DEBUG">
    &lt;appender-ref ref="SMTP" /> 
  &lt;/root>
&lt;/configuration>  </pre>

     <p>If your particular SMTP server does not handle address tags,
     you can still use them within the evaluator but remove them in
     the recipient address with the help of the <a
     href="../manual/layouts.html#replace">%replace</a> conversion
     word. Here is the relevant configuration snippet:</p>

     <pre class="prettyprint source">&lt;appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
  &lt;to>%replace(%mdc{txEmail}){'\+log', ''}&lt;/to>
  ...
&lt;/appender></pre>

     <p>This replaces any occurrence of the string "+log" within the
     string returned by %mdc{txEmail} with the empty string,
     effectively erasing +log from the recipient address.</p>

     <h3>Buffer management in very busy systems</h3>

     <p>The solution described so far provides an amazingly flexible
     solution to the initial problem. Indeed, any QA-engineer at
     Fooware.com, say Carol, can have the logs generated by requests
     she makes to Buscrit sent to her automatically by email. All she
     has to do is to suffix the user part in her email address with
     "+log" when she registers with Buscrit.
     </p>

     <p>By default <code>SMTPAppender</code> will cap the number of
     buffers it maintains to the value of the <span
     class="option">maxNumberOfBuffers</span> option (64 by default)
     and automatically discards buffers untouched for at least 30
     minutes. While this approach will work nicely in a test
     environment with few transactions, in a very busy production
     system, these buffer management mechanisms will cause Carol to
     receive <a
     href="../manual/appenders.html#bufferManagement">truncated log
     buffers</a>.  </p>

     <p>To deal with this problem, we instruct SMTPAppender to discard
     the appropriate buffer at the end of each transaction. This is done by
     logging an event marked as "FINALIZE_SESSION". Here is a modified
     version of <code>PrimeAction</code> which marks the end of a
     transaction with "FINALIZE_SESSION".
     </p>

     <pre class="prettyprint source">package ch.qos.logback.demo.prime;

<b>import static ch.qos.logback.classic.ClassicConstants.FINALIZE_SESSION_MARKER;</b>

public class PrimeAction extends Action {

  Logger logger = LoggerFactory.getLogger(PrimeAction.class);
  static Marker SMTP_TRIGGER = MarkerFactory.getMarker("SMTP_TRIGGER");
  static {
     // markers can hold references to other markers
     <b>SMTP_TRIGGER.add(FINALIZE_SESSION_MARKER);</b>
  }

  public ActionForward execute(ActionMapping actionMapping, ... ) throws Exception {

    Long number = form.getNumber();
    try {
      ...
    } finally {
      <b>logger.info(SMTP_TRIGGER, "Prime computation ended");</b>
      MDC.put("txId", null); // clear txId asap to avoid accidental rebirth
    }
  }
} </pre>


   <p>Not that at the end of each transaction the appropriate buffer
   is discarded, we can increase the value of <span
   class="option">maxNumberOfBuffers</span> as shown in the next
   configuration file..
   </p>

   <pre class="prettyprint   source">&lt;configuration scan="true" scanPeriod="3 seconds">

  &lt;statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" /&gt;

  &lt;appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
    &lt;SMTPHost>NAME_OF_SMTP_HOST&lt;/SMTPHost>
    &lt;to>%mdc{txEmail}&lt;/to>
    &lt;from>&lt;/from>
    &lt;subject>Prime - %mdc{number}&lt;/subject>

    &lt;layout class="ch.qos.logback.classic.html.HTMLLayout">
       &lt;pattern>%date%level%logger{24}%msg&lt;/pattern>
    &lt;/layout>

    &lt;discriminator class="ch.qos.logback.classic.sift.MDCBasedDiscriminator">
      &lt;key>txId&lt;/key>
      &lt;defaultValue>default&lt;/defaultValue>
    &lt;/discriminator>

    <b>&lt;cyclicBufferTracker class="ch.qos.logback.core.spi.CyclicBufferTracker"></b>
      <b>&lt;maxNumberOfBuffers>512&lt;/maxNumberOfBuffers></b>
    <b>&lt;/cyclicBufferTracker></b>

    &lt;evaluator class="ch.qos.logback.classic.boolex.JaninoEventEvaluator">
      &lt;expression>
        (mdc != null &amp;amp;&amp;amp; mdc.get("txEmail") != null &amp;amp;&amp;amp;
            ((String) mdc.get("txEmail")).contains("+log") )
        &amp;amp;&amp;amp;
        (marker != null  &amp;&amp; marker.contains("SMTP_TRIGGER") )
      &lt;/expression>
    &lt;/evaluator>

  &lt;root level="DEBUG">
    &lt;appender-ref ref="SMTP" /> 
  &lt;/root>
&lt;/configuration>  </pre>

    <p>With these latest changes, we can selectively send isolated
    logs for selected transactions to the concerned recipient, even in
    very busy production systems without excessive memory consumption.
    </p>

     <script src="../templates/footer.js" type="text/javascript"></script>	
    </div>
  </body>
</html>
 